====== kvqc2_1.0.9 Troubleshooting ====== As of 25-11-2010, kvqc2-1.0.9 is in operation but still no data arrives at teh warehouse. Thanks to Bjorn for spotting this :-) ! Sendt: 25. november 2010 10:30:52 Emne: Re: kvqc2_1.0.9 Hei! Have done select in kvalobs DB and and checked in KDVH. Seems to me that nothing has been transfered to KDVH. Bjørn ====== Double Check dev-vm101 ====== Test setup * kvdatalistener running on dev-vm101 * listens to the kvServiced accrding to the setup in $HOME/etc/kvdatalistener.conf * Check the ouput from kvqc2 and monitor the kvServiced.log * Data picked up by kvdatalistener is also written to "rcvtest_data" in the kvalobs db. Børge has the version configured on dev-vm101 to only write Qc2 controlled records. ^An algorithm is Run^ Qc2: Looking up object in CORBA nameservice: corbaname::corbans.met.no:2809#kvtest-dev-vm101/kvServiceDataReady Data input by kvQc2: -- ProcessUnitT Writing Data -6.4 17850 2010-11-25 9:0:0 A corresponding signal is observed in kvServiced.log (all this below is seen (partly a fact that DEBUG mode is on in dev-vm101 and not in production)) 20101125201847: DEBUG (ServiceSubscriber) --------------- Closing the database connection! 20101125202116: DEBUG (dataReady) --------------- New data from ! 20101125202116: INFO (ServiceSubscriber) --------------- New database connection (PostgreSQL) created! 20101125202116: DEBUG (ServiceSubscriber) --------------- Created a new connection to the database! 20101125202116: DEBUG (ServiceSubscriber) --------------- DataReady received from <> (Unknown)! 20101125202116: DEBUG (ServiceSubscriber) --------------- CALL DataSubscribers: stationID: 17850 obstime: 2010-11-25 09:00:00 typeID: 330 20101125202116: DEBUG (service/getData) --------------- called ... 20101125202116: DEBUG (service/getData) --------------- isMaxClientReached: # : 0 max: 10000 20101125202116: INFO (service/getData) --------------- New database connection (PostgreSQL) created! 20101125202116: DEBUG (service/DataIterator) --------------- next: called ... 20101125202116: DEBUG (service/DataIterator/findData) --------------- stationid: 17850 currentEndTime: 0000-00-00 --:--:-- endTime: 0000-00-00 --:--:-- iData: 0 20101125202116: DEBUG (service/DataIterator/findData) --------------- select(17850, 2010-11-24 17:00:01, 2010-11-25 05:00:00 20101125202116: DEBUG (service/DataIterator/findData) --------------- data: nElements=77 20101125202116: DEBUG (service/DataIterator/findData) --------------- textData: nElements=0 20101125202116: DEBUG (service/DataIterator/findData) --------------- DataIteratorImpl::findData: return TRUE 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[0].dataList.length()=9 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[1].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[2].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[3].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[4].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[5].dataList.length()=8 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[6].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[7].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[8].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[9].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[10].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList->length()=12 20101125202116: DEBUG (service/DataIterator) --------------- text_data: 20101125202116: DEBUG (service/DataIterator) --------------- No ! 20101125202116: DEBUG (service/DataIterator) --------------- next: called ... 20101125202116: DEBUG (service/DataIterator/findData) --------------- stationid: 17850 currentEndTime: 2010-11-25 05:00:01 endTime: 2010-11-25 18:00:00 iData: 0 20101125202116: DEBUG (service/DataIterator/findData) --------------- select(17850, 2010-11-25 05:00:01, 2010-11-25 17:00:00 20101125202116: DEBUG (service/DataIterator/findData) --------------- data: nElements=52 20101125202116: DEBUG (service/DataIterator/findData) --------------- textData: nElements=0 20101125202116: DEBUG (service/DataIterator/findData) --------------- DataIteratorImpl::findData: return TRUE 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[0].dataList.length()=10 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[1].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[2].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[3].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[4].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[5].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList[6].dataList.length()=6 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList->length()=8 20101125202116: DEBUG (service/DataIterator) --------------- text_data: 20101125202116: DEBUG (service/DataIterator) --------------- No ! 20101125202116: DEBUG (service/DataIterator) --------------- next: called ... 20101125202116: DEBUG (service/DataIterator/findData) --------------- stationid: 17850 currentEndTime: 2010-11-25 17:00:01 endTime: 2010-11-25 18:00:00 iData: 0 20101125202116: DEBUG (service/DataIterator/findData) --------------- select(17850, 2010-11-25 17:00:01, 2010-11-25 18:00:00 20101125202116: DEBUG (service/DataIterator/findData) --------------- data: nElements=0 20101125202116: DEBUG (service/DataIterator/findData) --------------- textData: nElements=0 20101125202116: DEBUG (service/DataIterator/findData) --------------- DataIteratorImpl::findData: return TRUE 20101125202116: DEBUG (service/DataIterator) --------------- next: End of data reached (return false)! 20101125202116: DEBUG --------------- DataIteratorImpl::destroy: called! 20101125202116: DEBUG --------------- DataIteratorImpl::destroy: leaving! 20101125202116: DEBUG (service/getData) --------------- called ... 20101125202116: DEBUG (service/getData) --------------- isMaxClientReached: # : 1 max: 10000 20101125202116: INFO (service/getData) --------------- New database connection (PostgreSQL) created! 20101125202116: DEBUG (service/DataIterator) --------------- next: called ... 20101125202116: DEBUG (service/DataIterator/findData) --------------- stationid: 17850 currentEndTime: 0000-00-00 --:--:-- endTime: 0000-00-00 --:--:-- iData: 0 20101125202116: DEBUG (service/DataIterator/findData) --------------- select(17850, 2010-11-25 09:00:00, 2010-11-25 09:00:00 20101125202116: DEBUG (service/DataIterator/findData) --------------- data: nElements=6 20101125202116: DEBUG (service/DataIterator/findData) --------------- textData: nElements=0 20101125202116: DEBUG (service/DataIterator/findData) --------------- DataIteratorImpl::findData: return TRUE 20101125202116: DEBUG (service/DataIterator) --------------- next: obsDataList->length()=1 20101125202116: DEBUG (service/DataIterator) --------------- text_data: 20101125202116: DEBUG (service/DataIterator) --------------- No ! 20101125202116: DEBUG (service/DataIterator) --------------- next: called ... 20101125202116: DEBUG (service/DataIterator) --------------- next: End of data reached (return false)! 20101125202116: DEBUG --------------- DataIteratorImpl::destroy: called! 20101125202116: DEBUG --------------- DataIteratorImpl::destroy: leaving! 20101125202116: DEBUG (service/getData) --------------- called ... 20101125202116: DEBUG (service/getData) --------------- isMaxClientReached: # : 2 max: 10000 20101125202116: INFO (service/getData) --------------- New database connection (PostgreSQL) created! 20101125202116: DEBUG (service/DataIterator) --------------- next: called ... 20101125202116: DEBUG (service/DataIterator/findData) --------------- stationid: 17850 currentEndTime: 0000-00-00 --:--:-- endTime: 0000-00-00 --:--:-- iData: 0 20101125202116: DEBUG (service/DataIterator/findData) --------------- select(17850, 2010-11-25 09:00:00, 2010-11-25 09:00:00 20101125202116: DEBUG (service/DataIterator/findData) --------------- data: nElements=6 20101125202116: DEBUG (service/DataIterator/findData) --------------- textData: nElements=0 The corresponding data is also written into the rcvtest_data table: kvalobs=# select * from rcvtest_data; stationid | obstime | original | paramid | tbtime | typeid | sensor | level | corrected | controlinfo | useinfo | cfailed -----------+---------------------+-------------------+---------+---------------------+--------+--------+-------+-------------------+------------------+------------------+-------------------- 17850 | 2010-11-25 09:00:00 | -32767 | 211 | 2010-11-25 09:30:10 | 330 | 0 | 0 | -6.40000009536743 | 0000601100000000 | 5894700000000001 | QC1-4-211:1,QC2d-2 ====== Listen to operations ====== * Update "$HOME/etc/kvdatalistener.conf" to listen to murky: kvserver=kvalobs #kvserver=kvtest-dev-vm101 * Run a check on murky (trigger from config file (file time set back afterwards)). Qc2 Output: kvalobs@murky:/var/log/kvalobs$ tail -f Qc2.log --------------- Case 10: Single Linear 20101125201217: INFO --------------- Single Linear 20101125201218: INFO --------------- ProcessUnitT Writing Data 63.5 76905 2010-11-25 16:0:0 20101125201218: INFO --------------- ProcessUnitT Writing Data 68 76906 2010-11-25 16:0:0 20101125201219: INFO --------------- ProcessUnitT Writing Data 57.5 76906 2010-11-25 12:0:0 20101125201219: INFO --------------- ProcessUnitT Writing Data 59.5 76905 2010-11-25 12:0:0 20101125201220: INFO --------------- ProcessUnitT Writing Data 69.5 17090 2010-11-25 10:0:0 20101125201220: INFO --------------- ProcessUnitT Writing Data 64.3 17850 2010-11-25 9:0:0 kvalobs@murky:/var/log/kvalobs$ And the data arrives on dev-vm101: kvalobs=# select * from rcvtest_data where paramid=262; stationid | obstime | original | paramid | tbtime | typeid | sensor | level | corrected | controlinfo | useinfo | cfailed -----------+---------------------+----------+---------+---------------------+--------+--------+-------+-----------+------------------+------------------+-------------------- 76905 | 2010-11-25 16:00:00 | -32767 | 262 | 2010-11-25 17:30:11 | 11 | 0 | 0 | 63.5 | 0000601100000000 | 5894700000000001 | QC1-4-262:1,QC2d-2 76906 | 2010-11-25 16:00:00 | -32767 | 262 | 2010-11-25 17:30:11 | 11 | 0 | 0 | 68 | 0000601100000000 | 5894700000000001 | QC1-4-262:1,QC2d-2 76906 | 2010-11-25 12:00:00 | -32767 | 262 | 2010-11-25 13:30:10 | 11 | 0 | 0 | 57.5 | 0000601100000000 | 5894700000000001 | QC1-4-262:1,QC2d-2 76905 | 2010-11-25 12:00:00 | -32767 | 262 | 2010-11-25 13:30:10 | 11 | 0 | 0 | 59.5 | 0000601100000000 | 5894700000000001 | QC1-4-262:1,QC2d-2 17090 | 2010-11-25 10:00:00 | -32767 | 262 | 2010-11-25 10:45:56 | 502 | 0 | 0 | 69.5 | 0000601100000000 | 5894700000000001 | QC1-4-262:1,QC2d-2 (5 rows) kvalobs=# \q kvalobs@dev-vm101:~$ Double check that at least one of the rows is in rcvtest_data but not in the dev-vm101 data table! kvalobs=# select * from rcvtest_data where paramid=262 and cfailed like '%QC2%' and obstime>'yesterday' and stationid=17090; stationid | obstime | original | paramid | tbtime | typeid | sensor | level | corrected | controlinfo | useinfo | cfailed -----------+---------------------+----------+---------+---------------------+--------+--------+-------+-----------+------------------+------------------+-------------------- 17090 | 2010-11-25 10:00:00 | -32767 | 262 | 2010-11-25 10:45:56 | 502 | 0 | 0 | 69.5 | 0000601100000000 | 5894700000000001 | QC1-4-262:1,QC2d-2 (1 row) kvalobs=# select * from data where paramid=262 and cfailed like '%QC2%' and obstime>'yesterday' and stationid=17090; stationid | obstime | original | paramid | tbtime | typeid | sensor | level | corrected | controlinfo | useinfo | cfailed -----------+---------+----------+---------+--------+--------+--------+-------+-----------+-------------+---------+--------- (0 rows) and did come from murky: kvalobs@murky:/etc/kvalobs/Qc2Config$ psql kvalobs Welcome to psql 8.3.3, the PostgreSQL interactive terminal. Type: \copyright for distribution terms \h for help with SQL commands \? for help with psql commands \g or terminate with semicolon to execute query \q to quit kvalobs=# select * from data where paramid=262 and cfailed like '%QC2%' and obstime>'yesterday' and stationid=17090 and obstime='2010-11-25 10:00:00'; stationid | obstime | original | paramid | tbtime | typeid | sensor | level | corrected | controlinfo | useinfo | cfailed -----------+---------------------+----------+---------+---------------------+--------+--------+-------+-----------+------------------+------------------+-------------------- 17090 | 2010-11-25 10:00:00 | -32767 | 262 | 2010-11-25 10:45:56 | 502 | 0 | 0 | 69.5 | 0000601100000000 | 5894700000000001 | QC1-4-262:1,QC2d-2 (1 row) ====== OLD MATERIAL ====== ====== Propagate Qc2 Data Downstream ====== These notes have been compiled in relation to investigations of [[https://kvoss.bugs.met.no/show_bug.cgi?id=1298]]. kv2kl-Qc2test setup to run on dev-vm128 (or somewhere ???.... ) and retrieve data from dev-vm101 and send it to dev-vm116. *Observation* dev-vm101 kvalobs@dev-vm101:~$ psql Welcome to psql 8.3.3, the PostgreSQL interactive terminal. Type: \copyright for distribution terms \h for help with SQL commands \? for help with psql commands \g or terminate with semicolon to execute query \q to quit kvalobs=# select * from data where stationid=64330 and obstime='2010-11-01 11:00:00' and paramid=211; stationid | obstime | original | paramid | tbtime | typeid | sensor | level | corrected | controlinfo | useinfo | cfailed -----------+---------------------+----------+---------+---------------------+--------+--------+-------+-----------+------------------+------------------+---------- 64330 | 2010-11-01 11:00:00 | -32767 | 211 | 2010-11-01 11:30:25 | 311 | 0 | 0 | 4.2 | 0000001100000000 | 6894900000000000 | QC2d-2 (1 row) dev-vm116: kvalobs@dev-vm116:~$ psql kvalobs Welcome to psql 8.3.5, the PostgreSQL interactive terminal. Type: \copyright for distribution terms \h for help with SQL commands \? for help with psql commands \g or terminate with semicolon to execute query \q to quit kvalobs=# select * from kv2klima where cfailed like '%QC2%; kvalobs'# kvalobs=# select * from kv2klima where cfailed like '%QC2%'; kvalobs=# select * from kv2klima where cfailed like '%QC2%' and stationid=64330; ERROR: column "stationid" does not exist LINE 1: ...ct * from kv2klima where cfailed like '%QC2%' and stationid=... ^ kvalobs=# select * from kv2klima where cfailed like '%QC2%' and stnr=64330; stnr | dato | typeid | paramid | sensor | xlevel | original | corrected | useinfo | para_name | year | kvstamp | klstamp | old_name | controlinfo | cfailed -------+---------------------+--------+---------+--------+--------+----------+-----------+------------------+-----------+------+---------------------+----------------------------+----------+------------------+---------- 64330 | 2010-11-01 11:00:00 | 311 | 211 | 0 | 0 | -32767.0 | 4.2 | 6894900000000000 | | | 2010-11-01 11:30:25 | 2010-11-01 16:28:27.028156 | | 0000001100000000 | QC2d-2 (1 rad) murky: kvalobs@murky:~$ psql kvalobs Welcome to psql 8.3.3, the PostgreSQL interactive terminal. Type: \copyright for distribution terms \h for help with SQL commands \? for help with psql commands \g or terminate with semicolon to execute query \q to quit kvalobs=# select * from data where stationid=64330 and obstime='2010-11-01 11:00:00' and paramid=211; stationid | obstime | original | paramid | tbtime | typeid | sensor | level | corrected | controlinfo | useinfo | cfailed -----------+---------------------+----------+---------+---------------------+--------+--------+-------+-----------+------------------+------------------+--------- 64330 | 2010-11-01 11:00:00 | 3.6 | 211 | 2010-11-01 10:53:28 | 311 | 0 | 0 | 3.6 | 0111100000000010 | 7000000000000000 | (1 row) This looks like it worked ... i.e. it did not come from murky! But we fiddled with HQC at the end of the day and did this trigger the transfer? ====== Yes it works - but only when kv2kl is restarted ... ! ====== The following contains a mixture of output (note before and after comman bug fix too!) kvalobs=# select stnr,cfailed,dato,kvstamp,klstamp,paramid from kv2klima where dato between '2010-11-02 04:00:00' and '2010-12-01' and cfailed like '%QC2%'; stnr | cfailed | dato | kvstamp | klstamp | paramid -------+---------------------------------------------+---------------------+---------------------+----------------------------+--------- 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 09:16:11.74845 | 262 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 09:16:11.749468 | 213 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 09:16:11.750993 | 178 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 09:16:11.75226 | 211 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 09:16:11.753643 | 215 17850 | QC2d-2,comma-check | 2010-11-02 09:00:00 | 2010-11-02 09:30:11 | 2010-11-02 15:25:03.21991 | 215 17850 | QC2d-2 comma check | 2010-11-02 09:00:00 | 2010-11-02 09:30:11 | 2010-11-02 15:25:03.220992 | 211 17850 | QC2d-2,comma-check | 2010-11-02 09:00:00 | 2010-11-02 09:30:11 | 2010-11-02 15:26:00.685493 | 215 17850 | QC2d-2 comma check | 2010-11-02 09:00:00 | 2010-11-02 09:30:11 | 2010-11-02 15:26:00.686509 | 211 76750 | QC1-1-178:1,QC1-1-178x:1,QC2d-2 | 2010-11-02 10:00:00 | 2010-11-02 09:53:15 | 2010-11-02 15:27:17.934638 | 178 76750 | QC1-1-211:1,QC1-1-211x:1 QC2d-2 comma check | 2010-11-02 10:00:00 | 2010-11-02 09:53:15 | 2010-11-02 15:27:17.935708 | 211 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 15:27:39.226109 | 104 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 15:27:39.227082 | 262 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 15:27:39.228054 | 213 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 15:27:39.22904 | 178 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 15:27:39.230223 | 211 89940 | QC2d-2 | 2010-11-02 04:00:00 | 2010-11-02 04:30:17 | 2010-11-02 15:27:39.231342 | 215 89940 | QC2d-2,comma-check | 2010-11-02 10:00:00 | 2010-11-02 10:30:20 | 2010-11-02 15:27:39.337016 | 215 89940 | QC2d-2 | 2010-11-02 10:00:00 | 2010-11-02 10:30:20 | 2010-11-02 15:27:39.338129 | 178 89940 | QC2d-2 comma check | 2010-11-02 10:00:00 | 2010-11-02 10:30:20 | 2010-11-02 15:27:39.340064 | 211 (20 rows)