We've been debugging this all morning (US-timezone). We found
But, we don't see messages showing up in datagrepper or resultsdb in Fedora Infrastructure. Our current suspect is something in whatever process is bridging fedmsg -> fedora messaging, but we're not sure where to start probing this.
Here's a log of troubleshooting so far: https://pagure.io/fedora-ci/general/issue/82
cc: @jimbair @astepano @bgoncalv @bookwar @pingou
This is a pretty critical issue as CI test results stopped being visible for developers.
The one of possible ways for us to investigate it further is to revert Jenkins to the previous state (before the JMS plugin update)
But this is not a good way because: 1) there is no confidence in that it actually solves anything 2) it will delay the switch to Fedora Messaging for at least two more weeks.
That's why we need Fedora Infra input on it.
So I've been looking a little bit into this.
I've ran the command: fedmsg-tail --really-pretty --no-validate --query topic |grep centos on my laptop, batcave01 and the two datagrepper hosts. CI messages appeared fine on all four hosts.
fedmsg-tail --really-pretty --no-validate --query topic |grep centos
I then run the command: fedmsg-tail --really-pretty --query topic |grep centos in parallel on a second terminal in my laptop, on a second terminal on batcave and in one of the two datagrepper. The goal there was to determine if --no-validate made a difference or not. This would have been a way to check if there was a certificate/signature issue. The messages appeared with on all the consumer, with or without --no-validate.
fedmsg-tail --really-pretty --query topic |grep centos
--no-validate
I then realized the messages are uploaded in the database on busgateway01. So I went there and check the logs of fedmsg-hub: journalctl -lfu fedmsg-hub -n 100. This led me to find a traceback when receiving messages from the CI pipeline:
journalctl -lfu fedmsg-hub -n 100
ProgrammingError: (ProgrammingError) column "timestamp" is of type timestamp without time zone but expression is of type bigint LINE 1: ...allpackages-pr.package.test.functional.complete', 1574091970...
Looking in the error, it seem it is finding a timestamp with the value 1574091970506.
1574091970506
A little python code:
>>> import datetime >>> datetime.datetime.fromtimestamp(1574091970506) Traceback (most recent call last): File "<input>", line 1, in <module> datetime.datetime.fromtimestamp(1574091970506) ValueError: year 51850 is out of range
So I'm currently strongly suspecting that this is our issue :)
Going down the rabbit hole a little, it seems that the last 3 digits are the unwanted ones:
>>> datetime.datetime.fromtimestamp(1574091970506) Traceback (most recent call last): File "<input>", line 1, in <module> datetime.datetime.fromtimestamp(1574091970506) ValueError: year 51850 is out of range >>> datetime.datetime.fromtimestamp(157409197050) datetime.datetime(6958, 2, 5, 17, 57, 30) >>> datetime.datetime.fromtimestamp(15740919705) datetime.datetime(2468, 10, 22, 15, 41, 45) >>> datetime.datetime.fromtimestamp(1574091970) datetime.datetime(2019, 11, 18, 16, 46, 10) >>> datetime.datetime.fromtimestamp(157409197) datetime.datetime(1974, 12, 27, 21, 46, 37)
(Cf the one before last)
The older version of JMS plugin was not setting the timestamp, so we were sending with '0'. Since version 1.1.8 the plugin set timestamp and uses it in milliseconds.
https://wiki.jenkins.io/display/JENKINS/JMS+Messaging+Plugin
https://github.com/jenkinsci/jms-messaging-plugin/pull/131/files
the plugin set timestamp and uses it in milliseconds.
This is most likely the issue then. We're expecting that the timestamp is an UNIX timestamp: https://en.wikipedia.org/wiki/Unix_time which is in second.
So,, I think this is fixed now? Is there anything further to do here?
Yes, this is fixed and we can close it out. Thank you! Fix for those curious in case it wasn't listed above: https://github.com/bstinsonmhk/jms-messaging-plugin/tree/fix-fedmsg-timestamp
Metadata Update from @kevin: - Issue close_status updated to: Fixed - Issue status updated to: Closed (was: Open)